Enhance plugin logging to provide more context information and request IDs #9853
Conversation
Test the buildOption 1. Jetpack Beta
Option 2. Jurassic Ninja - available for logged-in A12s🚀 Launch a JN site with this branch 🚀 ℹ️ Install this Tampermonkey script to get more options. Build info:
Note: the build is updated when a new commit is pushed to this PR. |
|
Size Change: 0 B Total Size: 1.39 MB ℹ️ View Unchanged
|
src/Internal/LoggerContext.php
Outdated
| $entry_context = is_array( $context ) && array_key_exists( 'context', $context ) | ||
| ? $context['context'] | ||
| : []; | ||
| if ( ! array_key_exists( 'source', $entry_context ) || 'woopayments' !== $entry_context['source'] ) { |
There was a problem hiding this comment.
Let's use Logger::LOG_FILENAME instead of woopayments here:
| if ( ! array_key_exists( 'source', $entry_context ) || 'woopayments' !== $entry_context['source'] ) { | |
| if ( ! array_key_exists( 'source', $entry_context ) || Logger::LOG_FILENAME !== $entry_context['source'] ) { |
Overall, I was about to suggest significantly simplifying this set of conditions, but I realized that you might want to use the $entry_context to add to the log. Is that the case? Because otherwise, the third parameter for Logger->log() is useless, as it does not automatically appear in the output.
There was a problem hiding this comment.
I think that we can eventually drop the changes to pass context to the Logger, as it won't make sense for WooPayments. On an interesting note, WooCommerce logger appends context information, if it is present, to the end of the log entry.
There was a problem hiding this comment.
WooCommerce logger appends context information, if it is present, to the end of the log entry.
I tested this briefly, and the context that I provided did not appear in the log file. I'll look into how Woo core does it.
There was a problem hiding this comment.
It is not in the WooPayments log, because entries are processed by the new filter. But if you disable filter, you will see it.
There was a problem hiding this comment.
FYI I tinkered with a small parser, you can find it here: gist. You should be able to add it to the plugin codebase, and alter the log path.
The PR contains plenty of meaningful changes, and IMO is heading in the correct direction: We can identify failing requests, and there is plenty of context to understand what's going on.
The biggest topic for me is grouping the logs for requests. The PoC parser does not have any filters at the moment, but when it does, ex. by API URL or response status, a lot of relevant entries would be hidden.
| public static function set_value( $key, $value ) { | ||
| wcpay_get_container()->get( InternalLoggerContext::class )->set_value( $key, $value ); |
There was a problem hiding this comment.
Nothing to do with this PR in particular, but when we started the re-engineering project, and added src with the DI container, I was really hoping that we'd be able to refactor the whole plugin to work that way. Thus this feels like a hack, but I understand it is necessary.
There was a problem hiding this comment.
I wasn't aware about it, but sounds interesting. I think we way src is made to work is much easier to follow than the long lists of include or require operators in the other parts of plugin code.
| Logger::log( "REQUEST $method $redacted_url" ); | ||
| Logger::log( | ||
| 'HEADERS: ' | ||
| . var_export( $headers, true ) // phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_var_export | ||
| ); | ||
| Logger::log( Logger::format_object( 'HEADERS', $headers ) ); | ||
|
|
||
| if ( null !== $body ) { | ||
| Logger::log( | ||
| 'BODY: ' | ||
| . var_export( $redacted_params, true ) // phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_var_export | ||
| ); | ||
| Logger::log( Logger::format_object( 'BODY', $redacted_params ) ); |
There was a problem hiding this comment.
Now that we have the context, do we need to log things here as separate entries?
I imagine that we could store everything in context, and then only call log() once, either for the error, or successful response.
There was a problem hiding this comment.
I think it can be done in the next optimisation. I see the point, that we can log one Request object, but I'd do that if we use a similar object internally. However I think we can follow the structure of remote_request arguments when logging.
There was a problem hiding this comment.
After implementing the change I've noticed that we log redacted version of the arguments. I will update it, to follow the same structure, but use redacted data.
| */ | ||
| public static function format_object( $label, $object ) { | ||
| try { | ||
| $encoded = wp_json_encode( $object, JSON_PRETTY_PRINT | JSON_UNESCAPED_UNICODE | JSON_THROW_ON_ERROR ); |
There was a problem hiding this comment.
Small suggestion here, but could we add a string like JSON: at the beginning here? Then the parser would not be required to guess whether it is JSON that should be parsed.
Fixes #9892
Changes proposed in this Pull Request
grc.Testing instructions
woopayments-YYYY-MM-DD...logs in thewp-content/uploads/wc-logs/and see that the formatting is in place, e.g. like below:or with
grcrunning:npm run changelogto add a changelog file, choosepatchto leave it empty if the change is not significant. You can add multiple changelog files in one PR by running this command a few times.Post merge